[Tips] Boto3でDEBUGログを出力する

はじめに

藤本です。

みなさん、AWS API/SDKを利用していますか？ 今年の6月にBoto3(AWS SDK For Python)がリリースされました。 使いやすくていいですよね。

Boto3については下記エントリをご参照ください。 AWS SDK For Python (Boto3)がリリースされました！

今回はBoto3でDEBUGログメッセージを出力する方法をご紹介します。

概要

Boto3に限らずライブラリを利用する上で使い方はドキュメントで得ることができますが、トラブルシューティングとなるとドキュメントだけで追うのは難しいところです。エラーメッセージだけで原因を特定できればよいですが、どうしても汎用的なエラーメッセージで特定に至ることが難しいこともあります。ソースを読むことが出来ればよいのですが簡単ではありません。そんな時にトラブルシューティングのヒントを得るために多くのライブラリは普段出力しないDEBUGログメッセージを仕込んでいてくれます。Boto3も例外ではありません。

Pythonのライブラリに関して言えば、一般的にログ出力を仕込んだ上でNullHandlerが設定されていることが多いです。というかPythonとして推奨しています。 ライブラリのためのロギングの設定

NullHandlerが実装されている場合、ライブラリの利用者の実装次第で好きなようにログ出力を実装することができます。Boto3に至っては更にログ出力を簡単にしてくれるメソッドを用意されていますのでご紹介いたします。また今回はbotocoreのDEBUGログ出力の方法も合わせてご紹介します。

環境

• クライアント
• OS : OS X 10.10.5
• Python : 3.4.3
• boto3 : 1.1.3

やってみた

Boto3

• boto3.set_stream_logger

In [1]: import boto3
In [2]: boto3.set_stream_logger()

設定はこれだけです。

In [3]: boto3.resource('ec2')
2015-09-06 18:39:19,544 boto3.resources.factory [DEBUG] Loading ec2:ec2
Out[3]: ec2.ServiceResource()

ec2のServiceResourceを生成すると、1行DEBUGレベルのログメッセージが出力されています。ただBoto3自体まだ大きなソースコードではなく、ログ出力も少ないです。

続いて、botocoreでDEBUGログ出力を有効にしましょう。

botocore

• botocore.session.Session.set_debug_logger

In [4]: import botocore
In [6]: botocore.session.Session().set_debug_logger()

設定はこれだけです。

In [7]: boto3.resource('ec2')
2015-09-06 18:48:11,385 - botocore.client - DEBUG - Registering retry handlers for service: ec2
2015-09-06 18:48:11,388 - botocore.hooks - DEBUG - Event creating-client-class.ec2: calling handler
2015-09-06 18:48:11,421 - botocore.endpoint - DEBUG - Setting ec2 timeout as (60, 60)
2015-09-06 18:48:11,422 boto3.resources.factory [DEBUG] Loading ec2:ec2
2015-09-06 18:48:11,425 - botocore.hooks - DEBUG - Event creating-resource-class.ec2.ServiceResource: calling handler ._handler at 0x10871fe18>
Out[7]: ec2.ServiceResource()

botocoreで出力されるDEBUGログメッセージが追加されました。

これだけだとありがたみが感じられないので、Client-AWS間のやり取りを見てみましょう。

In [11]: for i in boto3.resource('ec2').instances.iterator():
....: print(i.id)
....:
2015-09-06 18:49:14,248 - botocore.client - DEBUG - Registering retry handlers for service: ec2
2015-09-06 18:49:14,250 - botocore.hooks - DEBUG - Event creating-client-class.ec2: calling handler
2015-09-06 18:49:14,275 - botocore.endpoint - DEBUG - Setting ec2 timeout as (60, 60)
2015-09-06 18:49:14,276 boto3.resources.factory [DEBUG] Loading ec2:ec2
2015-09-06 18:49:14,278 - botocore.hooks - DEBUG - Event creating-resource-class.ec2.ServiceResource: calling handler ._handler at 0x10871fe18>
2015-09-06 18:49:14,279 boto3.resources.collection [INFO] Calling paginated ec2:describe_instances with {}
2015-09-06 18:49:14,281 - botocore.endpoint - DEBUG - Making request for (verify_ssl=True) with params: {'query_string': '', 'url': 'https://ec2.ap-northeast-1.amazonaws.com/', 'method': 'POST', 'url_path': '/', 'headers': {'User-Agent': 'Boto3/1.1.3 Python/3.4.3 Darwin/14.5.0 Botocore/1.2.0 Resource'}, 'body': {'Version': '2015-04-15', 'Action': 'DescribeInstances'}}
2015-09-06 18:49:14,281 - botocore.hooks - DEBUG - Event request-created.ec2.DescribeInstances: calling handler >
2015-09-06 18:49:14,281 - botocore.auth - DEBUG - Calculating signature using v4 auth.
2015-09-06 18:49:14,281 - botocore.auth - DEBUG - CanonicalRequest:
POST
/

host:ec2.ap-northeast-1.amazonaws.com
user-agent:Boto3/1.1.3 Python/3.4.3 Darwin/14.5.0 Botocore/1.2.0 Resource
x-amz-date:20150906T094914Z
x-amz-security-token:AQoDYXdzED4akAKJOLGVV2EtD9egDNfsr3CYcSg4n3KXA9CyqNIj3RmqB0EHnDKbENuAGDuaUvcdfDimUdDpLjVTx1ORTNLT2XX4D3svr/M0+9DMlQbPOtcIgaWnmod1eUdo5ZzJRd6BtuaSnmgrT0qYexTiYbU4QmEqLf72ZB0z8pcRLWI1dZeEY+0JbTFZHV5oDLHXbo8ZiiWFznlms5upEiu+ujdk0z3//IqfXnUjepys/RbqIS3HTTXHMWTtCmWzMyAwEmNaqsqW1i4KuLdvbKxfVUr0YkYLPGxTxKVzxXr5fUuaDazgcoVhViRRberwzS+avOh17oDqDGkQG9s7RiiYfClM5Wc9fJRSR7lglYwuvJXa1Gq4NCCyka+vBQ==

host;user-agent;x-amz-date;x-amz-security-token
c9a7660c583dd5d40b678efbf5ea016a6efac4571fc3534fda99b0d1d998eb8e
2015-09-06 18:49:14,281 - botocore.auth - DEBUG - StringToSign:
AWS4-HMAC-SHA256
20150906T094914Z
20150906/ap-northeast-1/ec2/aws4_request
598c0e07b8f542a18d80099e3959ea38d52f0bf818acebc80b38de87351c3e3f
2015-09-06 18:49:14,286 - botocore.auth - DEBUG - Signature:
93d8388a420a44538e096387fe7412b6a6d3df3e092c2a9947358d4511fda5a9
2015-09-06 18:49:14,287 - botocore.endpoint - DEBUG - Sending http request: 2015-09-06 18:49:14,288 - botocore.vendored.requests.packages.urllib3.connectionpool - INFO - Starting new HTTPS connection (1): ec2.ap-northeast-1.amazonaws.com
2015-09-06 18:49:15,209 - botocore.vendored.requests.packages.urllib3.connectionpool - DEBUG - "POST / HTTP/1.1" 200 None
2015-09-06 18:49:15,219 - botocore.parsers - DEBUG - Response headers: {'date': 'Sun, 06 Sep 2015 09:49:14 GMT', 'server': 'AmazonEC2', 'transfer-encoding': 'chunked', 'vary': 'Accept-Encoding', 'content-type': 'text/xml;charset=UTF-8'}
2015-09-06 18:49:15,219 - botocore.parsers - DEBUG - Response body:
b'<!--?xml version="1.0" encoding="UTF-8"?-->\n
・・・（RESPONSE BODY省略）・・・
'
2015-09-06 18:49:15,230 - botocore.hooks - DEBUG - Event needs-retry.ec2.DescribeInstances: calling handler
2015-09-06 18:49:15,230 - botocore.retryhandler - DEBUG - No retry needed.
2015-09-06 18:49:15,230 boto3.resources.factory [DEBUG] Loading ec2:Instance
i-19d377eb
i-5b77cea9
i-021ba9f0

今回は対話式で設定していますが、もちろんスクリプトでも出力設定は可能です。 またファイルに出力したい場合、別途FileHandlerを実装することでファイル出力も可能です。

まとめ

いかがでしたでしょうか？ DEBUGログメッセージの出力はトラブルシューティングの用途ではもちろんですが、ライブラリの各プログラムの把握に役立ちます。最後の出力結果を見れば、各プログラムがどの順番で何をしているのかなんとなく把握できないでしょうか。またPythonのライブラリなのでソースコードを直接編集し、DEBUGログメッセージを出力したり、Pythonデバッガを仕込むことでより詳細なデバッグをすることも容易なのがよいですね。